Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add optional structured logs of RPC related events #66

Merged
merged 12 commits into from
Feb 24, 2024
Merged

Add optional structured logs of RPC related events #66

merged 12 commits into from
Feb 24, 2024

Conversation

rem1-dev
Copy link

@rem1-dev rem1-dev commented Feb 13, 2024 •
edited
Loading

Adding RPC related event logs that will be used in Blockstream Explorer project. The logs are structured as json object. This optional logging may be used in an enterprise/internal scenario for billing purposes. By default it's turned off.

The logs are controlled with a new --rpc-logging command line option. Command line option possible values, and example structured logs they produce, are as following:

  • --rpc-logging full results in logs:
ELECTRUM-RPC-LOGGER: {"event":"connection established","source":{"ip":"127.0.0.1","port":59877}}
ELECTRUM-RPC-LOGGER: {"event":"rpc request","id":18,"method":"blockchain.scripthash.get_history","params":["6b63eef944d982701eb2d0dbb8ee900f42d8e79fe3d1ea473602c0edc87c34f6"],"source":{"ip":"127.0.0.1","port":59877}}
ELECTRUM-RPC-LOGGER: {"duration_µs":114,"event":"rpc response","id":18,"method":"blockchain.scripthash.get_history","payload_size":37,"source":{"ip":"127.0.0.1","port":59877}}
ELECTRUM-RPC-LOGGER: {"event":"connection closed","source":{"ip":"127.0.0.1","port":59877}}
  • --rpc-logging no-params excludes RPC request params to be logged, results in logs like:
ELECTRUM-RPC-LOGGER: {"event":"connection established","source":{"ip":"127.0.0.1","port":59886}}
ELECTRUM-RPC-LOGGER: {"event":"rpc request","id":18,"method":"blockchain.scripthash.get_history","params":null,"source":{"ip":"127.0.0.1","port":59886}}
ELECTRUM-RPC-LOGGER: {"duration_µs":78,"event":"rpc response","id":18,"method":"blockchain.scripthash.get_history","payload_size":37,"source":{"ip":"127.0.0.1","port":59886}}
ELECTRUM-RPC-LOGGER: {"event":"connection closed","source":{"ip":"127.0.0.1","port":59886}}```

shesek
shesek requested changes Feb 13, 2024
View reviewed changes
src/config.rs Outdated Show resolved Hide resolved
src/electrum/server.rs Outdated Show resolved Hide resolved
shesek
shesek reviewed Feb 18, 2024
View reviewed changes
src/electrum/server.rs Outdated Show resolved Hide resolved
shesek
shesek requested changes Feb 19, 2024
View reviewed changes
src/electrum/server.rs Outdated Show resolved Hide resolved
src/electrum/server.rs Outdated Show resolved Hide resolved
shesek
shesek reviewed Feb 20, 2024
View reviewed changes
src/electrum/server.rs Outdated Show resolved Hide resolved
@shesek
Copy link
Collaborator

shesek commented Feb 21, 2024

I was thinking that it might be useful to log two extra things - the jsonrpc id field so that the rpc request and rpc response entries can be matched to each-other, and the time it took to process the request.

I'm not sure whether these are necessary or not. If not, we can go ahead and merge.

@rem1-dev
Copy link
Author

rem1-dev commented Feb 21, 2024 •
edited
Loading

Yes, it's good idea to add id into req and resp logs. Did you mean id that we can get from cmd variable: cmd.get("id")? I added that.

rem1-dev and others added 4 commits February 22, 2024 16:26
@rem1-dev
Adding json id to log
83e904a
@shesek
Refactor: handle rpc replies inside the match arm
9dda728 
This makes `method_into` unnecessary and allows using the `id` variable
instead of reading `cmd` again. This also makes it easier to log time
durations (added in a followup commit).
@shesek
Some minor formatting and refactoring changes
e7abc4d
@shesek
Log the time duration for processing RPC requests
bc08fde
@shesek
Copy link
Collaborator

shesek commented Feb 22, 2024

I made some minor formatting/refactoring suggestions and added the time duration for processing requests in a branch. What do you think?

@rem1-dev
Copy link
Author

rem1-dev commented Feb 22, 2024 •
edited
Loading

It looks good to me. I also updated PR description to be more verbose on why we're adding it.

@shesek
Copy link
Collaborator

shesek commented Feb 23, 2024

Great :) Can you apply the changes on your branch and rebase?

@rem1-dev
Copy link
Author

I applied your changes + I changed duration timestamp field to microseconds because when I tested it I never got duration > 1s and that field was always 0. Re rebase: not sure what should I rebase on. Branch is up-to date with new-index

@shesek shesek self-requested a review February 24, 2024 06:49
@shesek shesek merged commit f9eeb34 into Blockstream:new-index Feb 24, 2024
1 check passed
@shesek
Copy link
Collaborator

shesek commented Feb 24, 2024 •
edited
Loading

Thanks!

I accidentally merged without squashing, looking into fixing this

junderw pushed a commit to junderw/electrs that referenced this pull request May 1, 2024
@wiz
Merge pull request Blockstream#66 from mempool/junderw/periodic_log_p…
e4b8bad 
…rogress

Feature: Log every 10k blocks to help show progress during initial sync
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@shesek shesek shesek approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@rem1-dev @shesek